App Runner環境で生じた障害調査とAWS WAFによる暫定対策を実施しました

App Runner 環境で発生していた遅延とエラー率上昇の問題調査と、暫定対策として導入したAWS WAF利用について紹介します。

#AWS App Runner

#AWS WAF

#AWS

#Amazon Athena

#Amazon CloudFront

suzuki.ryo

2024.06.05

6/4 10:30 〜 11:50 (JST) App Runner 環境で発生した、遅延とエラー率が上昇する事象について、実施した対応について紹介させていただきます。

App Runner

App Runnerのダッシュボードを利用して、稼働状態の確認。

正常応答(HTTP 2xx)数が減少
エラー応答(HTTP 4xx、5xx)と、レイテンシーが増加

の発生を確認しました。

AppRunnerメトリクス

App Runnerのアプリログを、エラー応答、レイテンシーが増加した時間帯を指定して確認。タイムアウトに伴うエラーが記録されていました。

AppRunnerアプリログ

アプリケーションログ、 CloudWatch Logsの「ログ異常検出」でも、タイムアウトに関連するログの急増が確認できました。

AppRunnerログ異常検出

アクセスログ調査

準備

外部からの大量アクセス、DoS、DDoSの可能性を確認するため、App Runnerの前段の CloudFrontの標準アクセスログの調査を行いました。

対象の CloudFront、標準アクセスログはS3にそのまま出力する設定で利用中。

Athenaで不要なフルスキャンを避けるために、作業用のS3バケットを用意しました。

TEMP_S3='s3://athena-temp-ap-northeast-1-000000000000/'
aws s3 mb ${TEMP_S3}

s3 syncコマンドを利用して、調査対象となる時間帯を含むログを作業用S3バケットにコピーしました。

LOG_S3='s3://cloudfront-logs-ap-northeast-1-00000000/xxxx/'
aws s3 sync --dryrun --exclude '*' --include '*2024-06-04-0[0,1,2,3]*.gz' ${LOG_S3} ${TEMP_S3} 
aws s3 sync --exclude '*' --include '*2024-06-04-0[0,1,2,3]*gz' ${LOG_S3} ${TEMP_S3}

Athenaのテーブルを AWSドキュメントに記載された、CloudFrontの標準ログ用のサンプルを踏襲、作業用S3バケットのログが対象となる指定で作成しました。

Amazon CloudFront ログのクエリ

CREATE EXTERNAL TABLE IF NOT EXISTS cloudfront_standard_logs (
  `date` DATE,
  time STRING,
  x_edge_location STRING,
  sc_bytes BIGINT,
  c_ip STRING,
  cs_method STRING,
  cs_host STRING,
  cs_uri_stem STRING,
  sc_status INT,
  cs_referrer STRING,
  cs_user_agent STRING,
  cs_uri_query STRING,
  cs_cookie STRING,
  x_edge_result_type STRING,
  x_edge_request_id STRING,
  x_host_header STRING,
  cs_protocol STRING,
  cs_bytes BIGINT,
  time_taken FLOAT,
  x_forwarded_for STRING,
  ssl_protocol STRING,
  ssl_cipher STRING,
  x_edge_response_result_type STRING,
  cs_protocol_version STRING,
  fle_status STRING,
  fle_encrypted_fields INT,
  c_port INT,
  time_to_first_byte FLOAT,
  x_edge_detailed_result_type STRING,
  sc_content_type STRING,
  sc_content_len BIGINT,
  sc_range_start BIGINT,
  sc_range_end BIGINT
)
ROW FORMAT DELIMITED 
FIELDS TERMINATED BY '\t'
LOCATION 's3://athena-temp-ap-northeast-1-000000000000/'
TBLPROPERTIES ( 'skip.header.line.count'='2' )

Athena解析

IPアドレス、UserAgent

過負荷の原因となったIPアドレス、UserAgentを求めました。

select
  a.*,
  a.required_time_sum / b.required_time_sum * 100
from
  (
    SELECT
      c_ip,
      substr(cs_user_agent, 1, 32) as cs_ua,
      count(1) as request_count,
      sum(time_taken) as required_time_sum
    FROM
      "default"."cloudfront_standard_logs"
    group by
      c_ip,
      cs_user_agent
    order by
      sum(time_taken) desc
  ) a, (
    SELECT
      sum(time_taken) as required_time_sum
    FROM
      "default"."cloudfront_standard_logs"
  ) b
order by
  a.required_time_sum desc
limit
  10

負荷の10%相当が2つのIPである事。 UserAgent情報より、Pythonスクリプトと、kendraによるクローラーによる過負荷の可能性が確認されました。

c_ip	cs_ua	request_count	required_time_sum	所要時間比率(%)
2600:1900:2000::::*	python-requests/2.32.3	18353	22470.455	6.7
13.114..	amazon-kendra-customer-id-ca0d58	5160	16303.138	4.8
54.249..	HatenaBlog-bot/0.02%20(+https://	1228	6086.256	1.8
54.249..	HatenaBlog-bot/0.02%20(+https://	1141	5512.005	1.6
43.206..*	curl/8.3.0	207	4162.735	1.2
107.178..	Hatena-Favicon/2%20(https://www.	989	2848.572	0.8
3.224..	Mozilla/5.0%20(Macintosh;%20Inte	602	1863.912	0.6
40.77..	Mozilla/5.0%20AppleWebKit/537.36	351	1732.096	0.5
52.70..	Mozilla/5.0%20(Macintosh;%20Inte	539	1717.954	0.5
107.178..	Hatena-Favicon/2%20(https://www.	481	1573.606	0.5

10分毎の遷移

上位2つのIPアドレスに限定し、リクエスト数、所要時間の遷移を確認しました。

SELECT
  substr(time, 1, 4) || '0' as time_HHm0,
  count(1) as request_count,
  sum(time_taken) as required_time_sum
FROM
  "default"."cloudfront_standard_logs"
where
  c_ip = '2600:1900:2000:**::*:**'
group by
  substr(time, 1, 4) || '0'
order by
  time_HHm0

Python

time_HHm0	request_count	required_time_sum
0:00	588	23.019001
0:10	1175	21.003
0:20	1357	102.297
0:30	261	4.396
0:40	908	40.65
0:50	461	15.831
1:00	641	20.357
1:10	1600	107.948
1:20	942	156.14
1:30	516	115.716
1:40	989	757.788
1:50	162	267.442
2:00	654	1783.432
2:10	1530	4276.497
2:20	905	1023.052
2:30	428	1915.644
2:40	738	4008.708
2:50	409	2037.077
3:00	697	1458.379
3:10	1375	1519.558
3:20	1045	2004.031
3:30	461	302.908
3:40	511	508.582

遅延やエラー応答の割合が顕著に増加した11時台、多数のリクエストと、長い応答時間が記録されていました。

kendra

time_HHm0	request_count	required_time_sum
1:00	275	467.917
1:10	716	2171.106
1:20	349	2188.694
1:30	521	2165.101
1:40	354	2153.986
1:50	517	2113.016
2:00	309	1976.889
2:10	361	741.236
2:20	281	261.597
2:30	65	250.167
2:40	60	313.376
2:50	125	799.051
3:10	99	192.564
3:20	100	210.747
3:30	56	136.44
3:40	1	1.92